src: trace threadpool event #44458

theanarkh · 2022-08-30T16:30:07Z

trace threadpool events, such as APIs of Blob, zlib, crypto and node_api.

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
documentation is changed or added
commit message follows commit guidelines

src/threadpoolwork-inl.h

src/node_internals.h

src/threadpoolwork-inl.h

doc/api/tracing.md

src/node_internals.h

src/threadpoolwork-inl.h

theanarkh · 2022-09-09T19:56:57Z

@legendecas @RaisinTen Hi, can we just trace the total time of work. the code is as follows.

void ThreadPoolWork::ScheduleWork() {
  env_->IncreaseWaitingRequestCounter();

  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(...);

  int status = uv_queue_work(
      env_->event_loop(),
      &work_req_,
      [](uv_work_t* req) {
        ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
        self->DoThreadPoolWork();
      },
      [](uv_work_t* req, int status) {
        ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
        self->env_->DecreaseWaitingRequestCounter();

        TRACE_EVENT_NESTABLE_ASYNC_END1(...);

        self->AfterThreadPoolWork(status);
      });
  CHECK_EQ(status, 0);
}

Or trace all the time by two different event type.

void ThreadPoolWork::ScheduleWork() {
  env_->IncreaseWaitingRequestCounter();

  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(...);

  int status = uv_queue_work(
      env_->event_loop(),
      &work_req_,
      [](uv_work_t* req) {
        ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
        TRACE_EVENT_BEGIN(...);
        self->DoThreadPoolWork();
        TRACE_EVENT_END(...);
      },
      [](uv_work_t* req, int status) {
        ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
        self->env_->DecreaseWaitingRequestCounter();

        TRACE_EVENT_NESTABLE_ASYNC_END1(...);

        self->AfterThreadPoolWork(status);
      });
  CHECK_EQ(status, 0);
}

legendecas · 2022-09-14T12:24:10Z

I'd still find that tracing the synchronous event is important. So the latter alternative is LGTM.

theanarkh · 2022-09-14T18:39:56Z

It seems we can not use TRACE_EVENT_BEGIN0 and TRACE_EVENT_END0 in another thread, i will take a look later.
https://github.com/nodejs/node/actions/runs/3054446637/jobs/4926355622.

theanarkh · 2022-10-26T00:42:04Z

@legendecas Hi, it seems the TRACE_EVENT_xx is not thread-safe, so i record the time of synchronous API call in args field of async event. what do you think ?

legendecas · 2022-10-26T02:25:11Z

@theanarkh The macros are declared to be thread-safe. If there is any problem related to thread safety, it should be fixed.

I'd find the problem here is related to the incomplete shutdown -- e.g. the global state of the tracing controller is not reset after the platform is shut down https://github.com/nodejs/node/blob/main/src/tracing/trace_event.cc#L8. This global state is used in the macro expansion: https://github.com/nodejs/node/blob/main/src/tracing/trace_event.h#L474. We should properly shut down the platform with the tracing global state.

theanarkh · 2022-10-26T14:05:44Z

Do you mean this test case https://github.com/nodejs/node/actions/runs/3054446637/jobs/4926355622 ? I remember when i change common.platformTimeout(10) to common.platformTimeout(100), the test exits normally🤔.

legendecas · 2022-10-26T16:47:57Z

@theanarkh yeah, IIUC that test case is exactly testing a premature exit while the async work is still in progress.

nodejs-github-bot · 2022-10-31T22:58:23Z

CI: https://ci.nodejs.org/job/node-test-pull-request/47605/

nodejs-github-bot · 2022-11-01T04:21:14Z

Landed in 8fb282e

When the process exits, there may be tasks in the thread pool that need to access data in the platform, such as trace agent. So make sure the thread pool exits first. see #44458 PR-URL: #45226 Refs: #44458 Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Santiago Gimeno <santiago.gimeno@gmail.com> Reviewed-By: Juan José Arboleda <soyjuanarbol@gmail.com>